JVM Minor GC vs Major GC vs Full GC

发表于 | 分类于 ， ，

Introduction

The post expects the reader to be familiar with generic garbage collection principles built into the JVM. Division of Heap into Eden, Survivor and Tenured/Old spaces, generational hypothesis(假设) and different GC algorithms are beyond the scope of this post.

Difference

Minor GC

Collecting garbage from Young space (consisting of Eden and Survivor spaces) is called a Minor GC.

This definition is both clear(清晰的) and uniformly(统一的) understood. But there are still some interesting take-aways you should be aware of when dealing with Minor Garbage Collection events:

  • Minor GC is always triggered when JVM is unable to allocate space for a new Object, e.g. the Eden is getting full. So the higher the allocation rate, the more frequently Minor GC is executed.

  • Whenever the pool is filled, its entire content is copied and the pointer can start tracking the free memory from zero again. So instead of(而不是…) classical(传统的) Mark, Sweep and Compact, cleaning Eden and Survivor spaces is carried out with Mark and Copy instead. So, no fragmentation(内存碎片) actually takes place inside Eden or Survivor spaces. The write pointer is always residing on the top of the used pool.

  • During a Minor GC event, Tenured generation is effectively ignored. References from tenured generation to young generation are considered de facto GC roots. References from young generation to Tenured generation are simply ignored during the markup phase.

  • Against common belief, all Minor GCs do trigger stop-the-world pauses, stopping the application threads. For most of the applications, the length of the pauses is negligible(微不足道的) latency-wise. This is true if most of the objects in Eden can be considered garbage and are never copied to Survivor/Old spaces. If the opposite is true and most of the newborn objects are not eligible for GC, Minor GC pauses start taking considerably more time.

Minor GC并不意味着不会STW，只是Minor GC会比Full GC开销小。

Major GC vs Full GC

  • Major GC is cleaning the Tenured space.
  • Full GC is cleaning the entire Heap – both Young and Tenured spaces.

This leads us to the point where instead of worrying whether the GC is called Major or Full GC, you should focus to finding out whether the GC at hand stopped all the application threads or was it able to progress concurrently with the application threads.

This confusion is even built right into the JVM standard tools. What I mean by that is best explained via an example. Lets compare the output of two different tools tracing the GC on a JVM running with Concurrent Mark and Sweep collector (-XX:+UseConcMarkSweepGC)

1
jstat -gc -t 4235 1s
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
Time    S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC       MU    CCSC   CCSU     YGC     YGCT    FGC    FGCT     GCT   
 5.7 34048.0 34048.0  0.0   34048.0 272640.0 194699.7 1756416.0   181419.9  18304.0 17865.1 2688.0 2497.6      3    0.275   0      0.000    0.275
 6.7 34048.0 34048.0 34048.0  0.0   272640.0 247555.4 1756416.0   263447.9  18816.0 18123.3 2688.0 2523.1      4    0.359   0      0.000    0.359
 7.7 34048.0 34048.0  0.0   34048.0 272640.0 257729.3 1756416.0   345109.8  19072.0 18396.6 2688.0 2550.3      5    0.451   0      0.000    0.451
 8.7 34048.0 34048.0 34048.0 34048.0 272640.0 272640.0 1756416.0  444982.5  19456.0 18681.3 2816.0 2575.8      7    0.550   0      0.000    0.550
 9.7 34048.0 34048.0 34046.7  0.0   272640.0 16777.0  1756416.0   587906.3  20096.0 19235.1 2944.0 2631.8      8    0.720   0      0.000    0.720
10.7 34048.0 34048.0  0.0   34046.2 272640.0 80171.6  1756416.0   664913.4  20352.0 19495.9 2944.0 2657.4      9    0.810   0      0.000    0.810
11.7 34048.0 34048.0 34048.0  0.0   272640.0 129480.8 1756416.0   745100.2  20608.0 19704.5 2944.0 2678.4     10    0.896   0      0.000    0.896
12.7 34048.0 34048.0  0.0   34046.6 272640.0 164070.7 1756416.0   822073.7  20992.0 19937.1 3072.0 2702.8     11    0.978   0      0.000    0.978
# Focus
13.7 34048.0 34048.0 34048.0  0.0   272640.0 211949.9 1756416.0   897364.4  21248.0 20179.6 3072.0 2728.1     12    1.087   1      0.004    1.091
14.7 34048.0 34048.0  0.0   34047.1 272640.0 245801.5 1756416.0   597362.6  21504.0 20390.6 3072.0 2750.3     13    1.183   2      0.050    1.233
# Focus
15.7 34048.0 34048.0  0.0   34048.0 272640.0 21474.1  1756416.0   757347.0  22012.0 20792.0 3200.0 2791.0     15    1.336   2      0.050    1.386
16.7 34048.0 34048.0 34047.0  0.0   272640.0 48378.0  1756416.0   838594.4  22268.0 21003.5 3200.0 2813.2     16    1.433   2      0.050    1.484

This snippet is extracted from the first 17 seconds after the JVM was launched.

Based on this information we could conclude that after 12 Minor GC runs two Full GC runs were performed, spanning 50ms in total. You would get the same confirmation via GUI-based tools, such as the jconsole or jvisualvm.

lets look at to the output of the garbage collection logs gathered from the same JVM launch. Apparently -XX:+PrintGCDetails tells us a different and more detailed story:

1
java -XX:+PrintGCDetails -XX:+UseConcMarkSweepGC eu.plumbr.demo.GarbageProducer
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
3.157: [GC (Allocation Failure) 3.157: [ParNew: 272640K->34048K(306688K), 0.0844702 secs] 272640K->69574K(2063104K), 0.0845560 secs] [Times: user=0.23 sys=0.03, real=0.09 secs] 
4.092: [GC (Allocation Failure) 4.092: [ParNew: 306688K->34048K(306688K), 0.1013723 secs] 342214K->136584K(2063104K), 0.1014307 secs] [Times: user=0.25 sys=0.05, real=0.10 secs] 
... cut for brevity ...
11.292: [GC (Allocation Failure) 11.292: [ParNew: 306686K->34048K(306688K), 0.0857219 secs] 971599K->779148K(2063104K), 0.0857875 secs] [Times: user=0.26 sys=0.04, real=0.09 secs] 
12.140: [GC (Allocation Failure) 12.140: [ParNew: 306688K->34046K(306688K), 0.0821774 secs] 1051788K->856120K(2063104K), 0.0822400 secs] [Times: user=0.25 sys=0.03, real=0.08 secs] 
12.989: [GC (Allocation Failure) 12.989: [ParNew: 306686K->34048K(306688K), 0.1086667 secs] 1128760K->931412K(2063104K), 0.1087416 secs] [Times: user=0.24 sys=0.04, real=0.11 secs] 
# Focus CMS Initial Mark 0.0041705 secs
13.098: [GC (CMS Initial Mark) [1 CMS-initial-mark: 897364K(1756416K)] 936667K(2063104K), 0.0041705 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
13.102: [CMS-concurrent-mark-start]
13.341: [CMS-concurrent-mark: 0.238/0.238 secs] [Times: user=0.36 sys=0.01, real=0.24 secs] 
13.341: [CMS-concurrent-preclean-start]
13.350: [CMS-concurrent-preclean: 0.009/0.009 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
13.350: [CMS-concurrent-abortable-preclean-start]
13.878: [GC (Allocation Failure) 13.878: [ParNew: 306688K->34047K(306688K), 0.0960456 secs] 1204052K->1010638K(2063104K), 0.0961542 secs] [Times: user=0.29 sys=0.04, real=0.09 secs] 
14.366: [CMS-concurrent-abortable-preclean: 0.917/1.016 secs] [Times: user=2.22 sys=0.07, real=1.01 secs] 
# Focus CMS Final Remark 0.0462010 secs
14.366: [GC (CMS Final Remark) [YG occupancy: 182593 K (306688 K)]14.366: [Rescan (parallel) , 0.0291598 secs]14.395: [weak refs processing, 0.0000232 secs]14.395: [class unloading, 0.0117661 secs]14.407: [scrub symbol table, 0.0015323 secs]14.409: [scrub string table, 0.0003221 secs][1 CMS-remark: 976591K(1756416K)] 1159184K(2063104K), 0.0462010 secs] [Times: user=0.14 sys=0.00, real=0.05 secs] 
14.412: [CMS-concurrent-sweep-start]
14.633: [CMS-concurrent-sweep: 0.221/0.221 secs] [Times: user=0.37 sys=0.00, real=0.22 secs] 
14.633: [CMS-concurrent-reset-start]
14.636: [CMS-concurrent-reset: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

Based on this information we can see that indeed after 12 Minor GC runs “something different” started happening. But instead two Full GC runs, this “different thing” was in reality just a single GC running in Tenured generation consisting of different phases:

  • Initial Mark phase, spanning for 0.0041705 seconds or approximately 4ms. This phase is a stop-the-world event stopping all application threads for initial marking.
  • Concurrenty executed Markup and Preclean phases. These are run concurrently with the application threads
  • Final Remark phase, spanning for 0.0462010 seconds or approximately 46ms. This phase is again stop-the-world event.
  • Concurrently executed Sweep operation. As the name states, this phase is also carried out concurrently without stopping the application threads.

So what we see from the actual garbage collection logs is that – instead(而不是) two Full GC operations, just one Major GC cleaning Old space was actually executed.

Pertaining Terms

  • S0C：年轻代中第一个survivor（幸存区）的容量 (kb)
  • S1C：年轻代中第二个survivor（幸存区）的容量 (kb)
  • S0U：年轻代中第一个survivor（幸存区）目前已使用空间 (kb)
  • S1U：年轻代中第二个survivor（幸存区）目前已使用空间 (kb)
  • EC：年轻代中Eden（伊甸园）的容量 (kb)
  • EU：年轻代中Eden（伊甸园）目前已使用空间 (kb)
  • OC：Old代的容量 (kb)
  • OU：Old代目前已使用空间 (kb)
  • PC：Perm(持久代)的容量 (kb)
  • PU：Perm(持久代)目前已使用空间 (kb)
  • YGC：从应用程序启动到采样时年轻代中gc次数
  • YGCT：从应用程序启动到采样时年轻代中gc所用时间(s)
  • FGC：从应用程序启动到采样时old代(全gc)gc次数
  • FGCT：从应用程序启动到采样时old代(全gc)gc所用时间(s)
  • GCT：从应用程序启动到采样时gc用的总时间(s)
  • NGCMN：年轻代(young)中初始化(最小)的大小 (kb)
  • NGCMX：年轻代(young)的最大容量 (kb)
  • NGC：年轻代(young)中当前的容量 (kb)
  • OGCMN：old代中初始化(最小)的大小 (kb)
  • OGCMX：old代的最大容量 (kb)
  • OGC：old代当前新生成的容量 (kb)
  • PGCMN：perm代中初始化(最小)的大小 (kb)
  • PGCMX：perm代的最大容量 (kb)
  • PGC：perm代当前新生成的容量 (kb)
  • S0：年轻代中第一个survivor（幸存区）已使用的占当前容量百分比
  • S1：年轻代中第二个survivor（幸存区）已使用的占当前容量百分比
  • E：年轻代中Eden（伊甸园）已使用的占当前容量百分比
  • O：old代已使用的占当前容量百分比
  • P：perm代已使用的占当前容量百分比
  • S0CMX：年轻代中第一个survivor（幸存区）的最大容量 (kb)
  • S1CMX ：年轻代中第二个survivor（幸存区）的最大容量 (kb)
  • ECMX：年轻代中Eden（伊甸园）的最大容量 (kb)
  • DSS：当前需要survivor（幸存区）的容量 (kb)（Eden区已满）
  • TT：持有次数限制
  • MTT ：最大持有次数限制

Reference

https://plumbr.io/blog/garbage-collection/minor-gc-vs-major-gc-vs-full-gc
https://www.cnblogs.com/zhangxiaoguang/p/5792468.html